**** dT 0.000
* top TEST ../../../../bin/vinyltest/tests/b00059.vtc starting
**** top extmacro def pkg_version=trunk
**** top extmacro def pkg_branch=trunk
**** top extmacro def pwd=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest
**** top extmacro def date(...)
**** top extmacro def string(...)
**** top extmacro def localhost=127.0.0.1
**** top extmacro def bad_backend=127.0.0.1:43200
**** top extmacro def listen_addr=127.0.0.1:0
**** top extmacro def bad_ip=192.0.2.255
**** top extmacro def topbuild=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub
**** top extmacro def topsrc=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/../..
**** top macro def testdir=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/../../../../bin/vinyltest/tests
**** top macro def tmpdir=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998
**** top macro def vtcid=vtc.695663.14f38998
** top === vtest "Run a lot of transactions through Unix domain sockets...
* top VTEST Run a lot of transactions through Unix domain sockets
** top === server s0 -listen "${tmpdir}/s1.sock" {
**** s0 macro def s0_addr=0.0.0.0
**** s0 macro def s0_port=0
**** s0 macro def s0_sock=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/s1.sock
** s0 Starting dispatch server
**** dT 0.001
** top === vinyl v1 -arg "-a ${tmpdir}/v1.sock -Wpoll" -vcl+backend {
** s0 Dispatch started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/s1.sock
**** dT 0.015
** v1 Launch
*** v1 CMD: cd ${pwd} && exec vinyld -d -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -M '127.0.0.1 35495' -P /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1/vinyld.pid -p vmod_path=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -a /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock -Wpoll
*** v1 CMD: cd /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest && exec vinyld -d -n /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1 -i v1 -l 2m -p auto_restart=off -p syslog_cli_traffic=off -p thread_pool_min=10 -p debug=+vtc_mode -p vsl_mask=+Debug,+H2RxHdr,+H2RxBody -p h2_initial_window_size=1m -p h2_rx_window_low_water=64k -M '127.0.0.1 35495' -P /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1/vinyld.pid -p vmod_path=/tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/vmod/.libs: -a /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock -Wpoll
**** dT 0.016
*** v1 PID: 695673
**** v1 macro def v1_pid=695673
**** v1 macro def v1_name=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1
**** dT 0.055
*** v1 debug|Warning: mlock() of VSM failed: Not owner
*** v1 debug| (1)
**** dT 0.060
*** v1 debug|Debug:
*** v1 debug|Version: vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4
*** v1 debug|Debug:
*** v1 debug|Platform: -jsolaris,-sdefault,-sdefault,-hcritbit
*** v1 debug|
*** v1 debug|200 292
*** v1 debug|-----------------------------
*** v1 debug|Vinyl Cache CLI 1.0
*** v1 debug|-----------------------------
*** v1 debug|-jsolaris,-sdefault,-sdefault,-hcritbit
*** v1 debug|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4
*** v1 debug|
*** v1 debug|Type 'help' for command list.
*** v1 debug|Type 'quit' to close CLI session.
*** v1 debug|Type 'start' to launch worker process.
*** v1 debug|
**** dT 0.156
**** v1 CLIPOLL 1 0x1 0x0 0x0
*** v1 CLI connection fd = 6
**** dT 0.157
*** v1 CLI RX 107
**** v1 CLI RX|kbhogoulsfepdpasrpqjyjdrirstnati
**** v1 CLI RX|
**** v1 CLI RX|Authentication required.
**** v1 CLI TX|auth eab67d0adab4a7fb558a6858c01385d86b68e4adb48c0503b55c710ac8e99ef5
*** v1 CLI RX 200
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|Vinyl Cache CLI 1.0
**** v1 CLI RX|-----------------------------
**** v1 CLI RX|-jsolaris,-sdefault,-sdefault,-hcritbit
**** v1 CLI RX|vinyl-cache-trunk revision 17ea9216e8091e8bd4b65a2e0b946c92de2125f4
**** v1 CLI RX|
**** v1 CLI RX|Type 'help' for command list.
**** v1 CLI RX|Type 'quit' to close CLI session.
**** v1 CLI RX|Type 'start' to launch worker process.
**** dT 0.158
**** v1 CLI TX|vcl.inline vcl1 << %XJEIFLH|)Xspa8P
**** v1 CLI TX|vcl 4.1;
**** v1 CLI TX|backend s0 { .path = "/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/s1.sock"; }
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|\tsub vcl_recv {
**** v1 CLI TX|\t\treturn (pass);
**** v1 CLI TX|\t}
**** v1 CLI TX|\tsub vcl_backend_fetch {
**** v1 CLI TX|\t\tset bereq.backend = s0;
**** v1 CLI TX|\t}
**** v1 CLI TX|
**** v1 CLI TX|
**** v1 CLI TX|%XJEIFLH|)Xspa8P
**** dT 0.258
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.358
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.458
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.558
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.658
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.758
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.858
*** v1 vsl|No VSL chunk found (child not started ?)
**** dT 0.867
*** v1 CLI RX 200
**** v1 CLI RX|Message from VCC-compiler:
**** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged
**** v1 CLI RX|Message from C-compiler:
**** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged
**** v1 CLI RX|Message from dlopen:
**** v1 CLI RX|Security: proc_setid missing, uid/gid unchanged
**** v1 CLI RX|VCL compiled.
**** v1 CLI TX|vcl.use vcl1
*** v1 CLI RX 200
**** v1 CLI RX|VCL 'vcl1' now active
** v1 Start
**** v1 CLI TX|start
**** dT 0.878
*** v1 debug|Debug:
*** v1 debug| Child (695757) Started
**** dT 0.910
*** v1 debug|Child launched OK
**** dT 0.912
*** v1 CLI RX 200
*** v1 wait-running
**** v1 CLI TX|status
*** v1 debug|Info: Child (695757) said Child starts
*** v1 debug|
*** v1 debug|Info:
*** v1 debug|
*** v1 debug|Child (695757) said Security: proc_setid missing, uid/gid unchanged
*** v1 debug|
*** v1 CLI RX 200
**** v1 CLI RX|Child in state running
**** v1 CLI TX|debug.listen_address
*** v1 CLI RX 200
**** v1 CLI RX|a0 /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock -
**** v1 CLI TX|debug.xid 1000
*** v1 CLI RX 200
**** v1 CLI RX|XID is 1000 chunk 1
**** v1 CLI TX|debug.listen_address
*** v1 CLI RX 200
**** v1 CLI RX|a0 /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock -
** v1 Listen on 0.0.0.0 0
**** v1 macro def v1_addr=0.0.0.0
**** v1 macro def v1_port=0
**** v1 macro def v1_sock=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 macro def v1_a0_addr=0.0.0.0
**** v1 macro def v1_a0_port=0
**** v1 macro def v1_a0_sock=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** dT 0.958
**** v1 vsl| 0 Debug - Acceptor poll space increased by 1024 to 1024
**** v1 vsl| 0 Debug - Acceptor poll space increased by 1024 to 1024
**** v1 vsl| 0 CLI - Rd vcl.load "vcl1" vcl_vcl1.1773724430.342047/vgc.so 1auto
**** v1 vsl| 0 CLI - Wr 200 52 Loaded "vcl_vcl1.1773724430.342047/vgc.so" as "vcl1"
**** v1 vsl| 0 CLI - Rd vcl.use "vcl1"
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 CLI - Rd start
**** v1 vsl| 0 Debug - sockopt: Setting SO_LINGER for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 0 Debug - sockopt: Setting SO_KEEPALIVE for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 0 Debug - sockopt: Setting SO_SNDTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 0 Debug - sockopt: Setting SO_RCVTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 0 CLI - Wr 200 0
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 76 a0 /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock -
**** v1 vsl| 0 CLI - Rd debug.xid 1000
**** v1 vsl| 0 CLI - Wr 200 19 XID is 1000 chunk 1
**** v1 vsl| 0 CLI - Rd debug.listen_address
**** v1 vsl| 0 CLI - Wr 200 76 a0 /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock -
**** dT 1.012
** top === client c1 -connect "${tmpdir}/v1.sock" {
** c1 Starting client
** top === client c2 -connect "${tmpdir}/v1.sock" {
** c2 Starting client
** c1 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock (1 iterations)
*** c1 Connect to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
** top === client c3 -connect "${tmpdir}/v1.sock" {
** c3 Starting client
*** c1 connected fd 16 to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
** c1 === loop 20 {
**** c1 Loop #0
** c1 === txreq -url /c1
**** c1 txreq|GET /c1 HTTP/1.1\r
**** c1 txreq|Host: 127.0.0.1\r
**** c1 txreq|User-Agent: c1\r
**** c1 txreq|\r
** c1 === rxresp
** top === client c1 -wait
** c1 Waiting for client
** c2 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock (1 iterations)
*** c2 Connect to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
*** c2 connected fd 17 to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** dT 1.013
** c2 === loop 20 {
** c3 Started on /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock (1 iterations)
**** c2 Loop #0
*** c3 Connect to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
** c2 === txreq -url /c2
**** c2 txreq|GET /c2 HTTP/1.1\r
**** c2 txreq|Host: 127.0.0.1\r
**** c2 txreq|User-Agent: c2\r
**** c2 txreq|\r
** c2 === rxresp
*** c3 connected fd 18 to /tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
** c3 === loop 20 {
**** c3 Loop #0
** c3 === txreq -url /c3
**** c3 txreq|GET /c3 HTTP/1.1\r
**** c3 txreq|Host: 127.0.0.1\r
**** c3 txreq|User-Agent: c3\r
**** c3 txreq|\r
** c3 === rxresp
*** s0 dispatch fd 4 -> s1
*** s0 dispatch fd 19 -> s2
*** s1 start with fd 4
** s1 === loop 10 {
**** s1 Loop #0
** s1 === rxreq
**** dT 1.014
---- s2 Assert error in server_dispatch_thread(), ../../../../bin/vinyltest/vtest2/src/vtc_server.c line 368: Condition(pthread_create(&s2->tp, ((void *)0), server_dispatch_wrk, s2) failed) not true. Errno=11 Resource temporarily unavailable
Backtrace:
fef230e3: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'vbt_execinfo+0x39 [0xfef230e3]
fef232f4: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_format+0x2d [0xfef232f4]
fef23362: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_dump+0x66 [0xfef23362]
807c399: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'vtc_log_VAS_Fail+0x65 [0x807c399]
fef226e9: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VAS_Fail+0x3a [0xfef226e9]
8089439: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'server_dispatch_thread+0x308 [0x8089439]
fed9a97f: /lib/libc.so.1'_thrp_setup+0x7f [0xfed9a97f]
fed9ac30: /lib/libc.so.1'_lwp_start+0x0 [0xfed9ac30]
**** s1 rxhdr|GET /c2 HTTP/1.1\r
**** s1 rxhdr|Host: 127.0.0.1\r
**** s1 rxhdr|User-Agent: c2\r
**** s1 rxhdr|X-Forwarded-For: 0.0.0.0\r
**** s1 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r
**** s1 rxhdr|X-Vinyl: 1006\r
**** s1 rxhdr|\r
**** s1 rxhdrlen = 127
**** s1 http[ 0] |GET
**** s1 http[ 1] |/c2
**** s1 http[ 2] |HTTP/1.1
**** s1 http[ 3] |Host: 127.0.0.1
**** s1 http[ 4] |User-Agent: c2
**** s1 http[ 5] |X-Forwarded-For: 0.0.0.0
**** s1 http[ 6] |Via: 1.1 v1 (Vinyl-Cache/trunk)
**** s1 http[ 7] |X-Vinyl: 1006
**** s1 bodylen = 0
* s1 Aborting execution, test failed
* s1 Aborting execution, test failed
*** s1 shutting fd -1 (server dispatch)
---- s1 Shutdown(WR) failed: Bad file number
**** dT 1.015
**** c2 rxhdr|HTTP/1.1 503 Backend fetch failed\r
**** c2 rxhdr|Date: Tue, 17 Mar 2026 05:13:51 GMT\r
**** c2 rxhdr|Server: Vinyl-Cache\r
**** c2 rxhdr|Content-Type: text/html; charset=utf-8\r
**** c2 rxhdr|Retry-After: 5\r
**** c2 rxhdr|X-Vinyl: 1004\r
**** c2 rxhdr|Age: 0\r
**** c2 rxhdr|Via: 1.1 v1 (Vinyl-Cache/trunk)\r
**** c2 rxhdr|Content-Length: 279\r
**** c2 rxhdr|Connection: keep-alive\r
**** c2 rxhdr|\r
**** c2 rxhdrlen = 252
**** c2 http[ 0] |HTTP/1.1
**** c2 http[ 1] |503
**** c2 http[ 2] |Backend fetch failed
**** c2 http[ 3] |Date: Tue, 17 Mar 2026 05:13:51 GMT
**** c2 http[ 4] |Server: Vinyl-Cache
**** c2 http[ 5] |Content-Type: text/html; charset=utf-8
**** c2 http[ 6] |Retry-After: 5
**** c2 http[ 7] |X-Vinyl: 1004
**** c2 http[ 8] |Age: 0
**** c2 http[ 9] |Via: 1.1 v1 (Vinyl-Cache/trunk)
**** c2 http[10] |Content-Length: 279
**** c2 http[11] |Connection: keep-alive
**** c2 c-l|
**** c2 c-l|
**** c2 c-l|
**** c2 c-l| 503 Backend fetch failed
**** c2 c-l|
**** c2 c-l|
**** c2 c-l| Error 503 Backend fetch failed
**** c2 c-l| Backend fetch failed
**** c2 c-l| Guru Meditation:
**** c2 c-l| XID: 1006
**** c2 c-l|
**** c2 c-l| Vinyl Cache server
**** c2 c-l|
**** c2 c-l|
**** c2 bodylen = 279
* c2 Aborting execution, test failed
*** c2 closing fd -1
**** dT 1.016
---- c2 Assert error in VTCP_close(), ../../../../lib/libvinyl/vtcp.c line 347: Condition(VTCP_Check(i)) not true. Errno=9 Bad file number
Backtrace:
fef230e3: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'vbt_execinfo+0x39 [0xfef230e3]
fef232f4: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_format+0x2d [0xfef232f4]
fef23362: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_dump+0x66 [0xfef23362]
807c399: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'vtc_log_VAS_Fail+0x65 [0x807c399]
fef226e9: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VAS_Fail+0x3a [0xfef226e9]
fef33ef5: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VTCP_close+0x5c [0xfef33ef5]
8063d9a: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'client_disc+0x29 [0x8063d9a]
808a564: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'sess_thread+0x1f0 [0x808a564]
fed9a97f: /lib/libc.so.1'_thrp_setup+0x7f [0xfed9a97f]
fed9ac30: /lib/libc.so.1'_lwp_start+0x0 [0xfed9ac30]
**** dT 1.058
**** v1 vsl| 1000 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 SessOpen c 0.0.0.0 0 a0 0.0.0.0 0 1773724431.196543 18
**** v1 vsl| 1001 Begin c sess 0 HTTP/1
**** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_KEEPALIVE non heredity for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_SNDTIMEO non heredity for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1000 Debug c sockopt: Test confirmed SO_RCVTIMEO non heredity for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1000 Debug c sockopt: SO_LINGER may be inherited for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1000 Debug c sockopt: Setting SO_KEEPALIVE for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1001 SessOpen c 0.0.0.0 0 a0 0.0.0.0 0 1773724431.196715 19
**** v1 vsl| 1000 Debug c sockopt: Setting SO_SNDTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1001 Debug c sockopt: SO_LINGER may be inherited for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1001 Debug c sockopt: Setting SO_KEEPALIVE for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1000 Debug c sockopt: Setting SO_RCVTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1001 Debug c sockopt: Setting SO_SNDTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1001 Debug c sockopt: Setting SO_RCVTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1002 Begin c sess 0 HTTP/1
**** v1 vsl| 1002 SessOpen c 0.0.0.0 0 a0 0.0.0.0 0 1773724431.196816 20
**** v1 vsl| 1000 Link c req 1003 rxreq
**** v1 vsl| 1001 Link c req 1004 rxreq
**** v1 vsl| 1002 Debug c sockopt: SO_LINGER may be inherited for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1002 Debug c sockopt: Setting SO_KEEPALIVE for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1002 Debug c sockopt: Setting SO_SNDTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1002 Debug c sockopt: Setting SO_RCVTIMEO for a0=/tmp/vtest.gcc13_m32_IPv4_uffix/_vtest_tmp/vtc.695663.14f38998/v1.sock
**** v1 vsl| 1002 Link c req 1005 rxreq
**** v1 vsl| 1006 Begin b bereq 1004 pass
**** v1 vsl| 1006 VCL_use b vcl1
**** v1 vsl| 1006 Timestamp b Start: 1773724431.197082 0.000000 0.000000
**** v1 vsl| 1006 BereqMethod b GET
**** v1 vsl| 1006 BereqURL b /c2
**** v1 vsl| 1006 BereqProtocol b HTTP/1.1
**** v1 vsl| 1006 BereqHeader b Host: 127.0.0.1
**** v1 vsl| 1006 BereqHeader b User-Agent: c2
**** v1 vsl| 1006 BereqHeader b X-Forwarded-For: 0.0.0.0
**** v1 vsl| 1006 BereqHeader b Via: 1.1 v1 (Vinyl-Cache/trunk)
**** v1 vsl| 1006 BereqHeader b X-Vinyl: 1006
**** v1 vsl| 1006 VCL_call b BACKEND_FETCH
**** v1 vsl| 1006 VCL_return b fetch
**** dT 1.059
**** v1 vsl| 1006 Timestamp b Fetch: 1773724431.197119 0.000036 0.000036
**** v1 vsl| 1006 Timestamp b Connected: 1773724431.197181 0.000098 0.000062
**** v1 vsl| 1006 BackendOpen b 23 s0 0.0.0.0 0 0.0.0.0 0 connect
**** v1 vsl| 1006 Timestamp b Bereq: 1773724431.197224 0.000141 0.000042
**** v1 vsl| 1006 FetchError b HTC eof (Unexpected end of input)
**** v1 vsl| 1006 BackendClose b 23 s0 close RX_BAD
**** v1 vsl| 1006 Timestamp b Beresp: 1773724431.198085 0.001003 0.000861
**** v1 vsl| 1006 Timestamp b Error: 1773724431.198088 0.001005 0.000002
**** v1 vsl| 1006 BerespProtocol b HTTP/1.1
**** v1 vsl| 1006 BerespStatus b 503
**** v1 vsl| 1006 BerespReason b Backend fetch failed
**** v1 vsl| 1006 BerespHeader b Date: Tue, 17 Mar 2026 05:13:51 GMT
**** v1 vsl| 1006 BerespHeader b Server: Vinyl-Cache
**** v1 vsl| 1006 VCL_call b BACKEND_ERROR
**** v1 vsl| 1006 BerespHeader b Content-Type: text/html; charset=utf-8
**** v1 vsl| 1006 BerespHeader b Retry-After: 5
**** v1 vsl| 1006 VCL_return b deliver
**** v1 vsl| 1006 Storage b umem Transient
**** v1 vsl| 1006 Length b 279
**** v1 vsl| 1006 BereqAcct b 127 0 127 0 0 0
**** v1 vsl| 1006 End b
**** v1 vsl| 1004 Begin c req 1001 rxreq
**** v1 vsl| 1004 Timestamp c Start: 1773724431.196818 0.000000 0.000000
**** v1 vsl| 1004 Timestamp c Req: 1773724431.196818 0.000000 0.000000
**** v1 vsl| 1004 VCL_use c vcl1
**** v1 vsl| 1004 ReqStart c 0.0.0.0 0 a0
**** v1 vsl| 1004 ReqMethod c GET
**** v1 vsl| 1004 ReqURL c /c2
**** v1 vsl| 1004 ReqProtocol c HTTP/1.1
**** v1 vsl| 1004 ReqHeader c Host: 127.0.0.1
**** v1 vsl| 1004 ReqHeader c User-Agent: c2
**** v1 vsl| 1004 ReqHeader c X-Forwarded-For: 0.0.0.0
**** v1 vsl| 1004 ReqHeader c Via: 1.1 v1 (Vinyl-Cache/trunk)
**** v1 vsl| 1004 VCL_call c RECV
**** v1 vsl| 1004 VCL_return c pass
**** v1 vsl| 1004 VCL_call c HASH
**** v1 vsl| 1004 VCL_return c lookup
**** v1 vsl| 1004 VCL_call c PASS
**** v1 vsl| 1004 VCL_return c fetch
**** v1 vsl| 1004 Link c bereq 1006 pass
**** v1 vsl| 1004 Timestamp c Fetch: 1773724431.198273 0.001454 0.001454
**** v1 vsl| 1004 RespProtocol c HTTP/1.1
**** v1 vsl| 1004 RespStatus c 503
**** v1 vsl| 1004 RespReason c Backend fetch failed
**** v1 vsl| 1004 RespHeader c Date: Tue, 17 Mar 2026 05:13:51 GMT
**** v1 vsl| 1004 RespHeader c Server: Vinyl-Cache
**** v1 vsl| 1004 RespHeader c Content-Type: text/html; charset=utf-8
**** v1 vsl| 1004 RespHeader c Retry-After: 5
**** v1 vsl| 1004 RespHeader c X-Vinyl: 1004
**** v1 vsl| 1004 RespHeader c Age: 0
**** v1 vsl| 1004 RespHeader c Via: 1.1 v1 (Vinyl-Cache/trunk)
**** v1 vsl| 1004 VCL_call c DELIVER
**** v1 vsl| 1004 VCL_return c deliver
**** v1 vsl| 1004 Timestamp c Process: 1773724431.198314 0.001495 0.000041
**** v1 vsl| 1004 Filters c
**** v1 vsl| 1004 RespHeader c Content-Length: 279
**** v1 vsl| 1004 RespHeader c Connection: keep-alive
**** v1 vsl| 1004 Timestamp c Resp: 1773724431.198415 0.001596 0.000100
**** v1 vsl| 1004 ReqAcct c 53 0 53 252 279 531
**** v1 vsl| 1004 End c
**** v1 vsl| 1001 SessClose c REM_CLOSE 0.003
**** v1 vsl| 1001 End c
**** dT 3.962
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724434 1.0
**** dT 6.964
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724437 1.0
**** dT 9.965
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724440 1.0
**** dT 12.967
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724443 1.0
**** dT 15.969
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724446 1.0
**** dT 18.970
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724449 1.0
**** dT 21.972
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724452 1.0
**** dT 24.976
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724455 1.0
**** dT 27.979
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724458 1.0
**** dT 30.981
**** v1 vsl| 0 CLI - Rd ping
**** v1 vsl| 0 CLI - Wr 200 19 PONG 1773724461 1.0
**** dT 31.012
---- c1 HTTP rx timeout (fd:16 30.000s)
**** dT 31.013
* top Aborting execution, test failed
* top RESETTING after ../../../../bin/vinyltest/tests/b00059.vtc
** c2 Waiting for client
** c3 Waiting for client
---- c3 HTTP rx timeout (fd:18 30.000s)
** s0 Waiting for server (3/-1)
** s1 Waiting for server (-1/4)
** s2 Waiting for server (-1/19)
* diag 0.0 Assert error in server_wait(), ../../../../bin/vinyltest/vtest2/src/vtc_server.c line 414:
* diag 0.0 Condition(pthread_join(s->tp, &res) failed) not true. (errno=3 No such process)
* diag 0.0 Backtrace:
* diag 0.0 fef230e3: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'vbt_execinfo+0x39 [0xfef230e3]
* diag 0.0 fef232f4: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_format+0x2d [0xfef232f4]
* diag 0.0 fef23362: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VBT_dump+0x66 [0xfef23362]
* diag 0.0 807c399: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'vtc_log_VAS_Fail+0x65 [0x807c399]
* diag 0.0 fef226e9: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/lib/libvinylapi/.libs/libvinylapi.so.3.1.0'VAS_Fail+0x3a [0xfef226e9]
* diag 0.0 808970d: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'server_wait+0xc5 [0x808970d]
* diag 0.0 8089b30: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'cmd_server+0x136 [0x8089b30]
* diag 0.0 8061517: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'reset_cmd+0x4c [0x8061517]
* diag 0.0 8061551: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'reset_cmds+0x23 [0x8061551]
* diag 0.0 80616cf: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'fail_out+0x76 [0x80616cf]
* diag 0.0 8061b27: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'exec_file+0x3f0 [0x8061b27]
* diag 0.0 8081d2b: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'start_test+0x53c [0x8081d2b]
* diag 0.0 80837fc: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'main+0x32b [0x80837fc]
* diag 0.0 805afbb: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'_start_crt+0x9a [0x805afbb]
* diag 0.0 805ae8a: /tmp/vtest.gcc13_m32_IPv4_uffix/varnish-cache/vinyl-cache-trunk/_build/sub/bin/vinyltest/.libs/vinyltest'_start+0x1a [0x805ae8a]
* diag 0.0
# top TEST ../../../../bin/vinyltest/tests/b00059.vtc FAILED (31.016) signal=6
FAIL tests/b00059.vtc (exit status: 2)